perf: batch structured log writes into a single aiofiles call - #1182
Conversation
_write_to_files() looped over the flush batch and issued one `await f.write(...)` per log entry. aiofiles implements every file method as `loop.run_in_executor(executor, partial(...))`, so each of those awaits is a full thread-pool round-trip -- not a cheap buffered write. With the default `buffer_size` of 100, a single flush cost 100 executor round-trips for structured_logs.jsonl, plus up to 100 more for error_logs.jsonl when the batch contained ERROR/CRITICAL entries. Serialise the batch first and issue one write per file. Output bytes, file paths, append semantics and error handling are unchanged; only the number of write() calls changes (N -> 1 per file). Adds TestLoggingServiceWriteToFiles covering the write-call count, the per-entry round trip through the file, append-not-truncate across two flushes, ERROR/CRITICAL routing to the separate file, and the empty batch. Non-vacuity proven against the per-entry loop: "_write_to_files issued 25 write() calls for 25 log entries" "_write_to_files issued 24 write() calls for 12 ERROR entries" Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
|
The latest updates on your projects. Learn more about Vercel for GitHub.
|
|
Warning Review limit reached
Next review available in: 28 minutes Enable usage-based reviews in Billing to review now. Otherwise, wait until the next included review is available. How can I continue?After more reviews become available, a review can be triggered using the To avoid repeated limits, reduce automatic review volume by pausing incremental auto-reviews earlier, using label-based review opt-in, excluding WIP or generated PR titles, or requesting reviews manually when the PR is ready. If your team needs uninterrupted high-volume reviews, an organization admin can enable usage-based reviews. How do review limits work?CodeRabbit enforces per-developer PR review limits for each organization. Most developers receive the normal plan review availability. For paid Pro and Pro+ PR reviews, CodeRabbit uses adaptive limits for sustained high-volume activity. When a developer's recent PR review activity reaches the 95th percentile or higher among CodeRabbit users, additional reviews become available more gradually as earlier reviews age out of the rolling window. Please refer docs for additional details. Review details⚙️ Run configurationConfiguration used: Repository YAML (base), Repository UI (inherited), Organization UI (inherited) Review profile: ASSERTIVE Plan: Pro Plus Run ID: ⛔ Files ignored due to path filters (1)
📒 Files selected for processing (1)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
Dependency Review✅ No vulnerabilities or license issues or OpenSSF Scorecard issues found.Snapshot WarningsEnsure that dependencies are being submitted on PR branches and consider enabling retry-on-snapshot-warnings. See the documentation for more information and troubleshooting advice. Scanned FilesNone |
|
@coderabbitai review Specific things I'd like challenged:
|
Agent Completion Truth Gate: NOT_APPLICABLEEvidence agrees. Machine-readable verdict{
"details": {},
"reasons": [],
"verdict": "not_applicable"
} |
🧩 Analysis chain🏁 Script executed: #!/bin/bash
set -euo pipefail
service='src/youtube_extension/backend/services/logging_service.py'
tests='tests/unit/test_logging_service.py'
printf '%s\n' '--- logging service outline ---'
ast-grep outline "$service" --items all --view expanded || true
printf '%s\n' '--- _write_to_files and surrounding code ---'
rg -n -C 18 'async def _write_to_files\b|def _write_to_files\b|buffer_size|log_buffer|flush_logs|asyncio\.gather|create_task' "$service" || true
printf '%s\n' '--- configuration and instantiation references ---'
rg -n -C 4 '\bLoggingService\s*\(|["'\'']buffer_size["'\'']|logging.*buffer|buffer.*logging' src tests -g '*.py' || true
printf '%s\n' '--- write-path tests ---'
if [ -f "$tests" ]; then
ast-grep outline "$tests" --items all --view expanded || true
rg -n -C 8 'WriteToFiles|batches_|empty_batch|appends_|error_logs_routed|write\(' "$tests" || true
fi
printf '%s\n' '--- aiofiles dependency metadata ---'
rg -n -C 3 'aiofiles' pyproject.toml requirements*.txt setup.cfg setup.py 2>/dev/null || trueLength of output: 20498 🏁 Script executed: #!/bin/bash
set -euo pipefail
printf '%s\n' '--- PR diff for logging-service files ---'
git diff --find-renames --unified=80 'HEAD^' 'HEAD' -- \
src/youtube_extension/backend/services/logging_service.py || true
printf '%s\n' '--- locate logging service tests ---'
fd -HI -t f '.*logging.*service.*\.py$|test_.*logging.*\.py$' . \
-E .git -E node_modules -E dist -E build | sort
printf '%s\n' '--- configuration injection and direct construction ---'
rg -n -C 8 '\bLoggingService\s*\(' . \
-g '*.py' -g '!**/.git/**' -g '!**/node_modules/**' -g '!**/dist/**' -g '!**/build/**' || true
printf '%s\n' '--- test class and direct _write_to_files calls anywhere in checkout ---'
rg -n -C 6 'TestLoggingServiceWriteToFiles|_write_to_files\s*\(|buffer_size.*:' . \
-g '*.py' -g '!**/.git/**' -g '!**/node_modules/**' -g '!**/dist/**' -g '!**/build/**' || true
printf '%s\n' '--- aiofiles version resolution inputs ---'
fd -HI -t f '(^|.*\/)(uv\.lock|poetry\.lock|pdm\.lock|requirements.*\.txt|pyproject\.toml)$' . \
-E .git -E node_modules -E dist -E build -x sh -c 'echo "--- $1"; rg -n -C 2 "aiofiles" "$1" || true' sh {}Length of output: 18194 🤖 web_search executed:
Length of output: 5090
✅ Action performedReview finished.
|
There was a problem hiding this comment.
Pull request overview
Optimizes structured logging by batching each flush into one asynchronous write per output file.
Changes:
- Serializes structured and error log batches before writing.
- Adds regression tests for batching, ordering, append behavior, routing, and empty batches.
Reviewed changes
Copilot reviewed 2 out of 2 changed files in this pull request and generated no comments.
| File | Description |
|---|---|
src/youtube_extension/backend/services/logging_service.py |
Replaces per-entry writes with batched writes. |
tests/unit/test_logging_service.py |
Tests write counts and preserved output behavior. |
|
Automated triage note on the CodeRabbit review — two corrections worth flagging before this is read as blocked: 1. CodeRabbit finding #5 ("the claimed tests are absent from this PR checkout") is a false positive. The test file is present at head
The cause is CodeRabbit's own path filter: its comment lists 2. The only failing check is a cancelled deploy, not a code failure. The commit status shows The remaining CodeRabbit points are non-blocking and yours to weigh: #1 (soften the "cost scales only with call count" wording) and #3 (the bounded-memory claim holds for the default Terminal state: awaiting merge approval — mergeable once the Vercel status is re-run/dismissed. Not auto-merging: no Generated by Claude Code |
Review — batched log writesCode: correct and behaviour-preserving. The per-entry Tests: comprehensive and non-vacuous. The 7 new tests cover call-count, per-file routing, append semantics, ordering/JSON-parseability, and the empty batch. The PR demonstrates they fail against the pre-batch loop (25→1, 24→2 write assertions), so they genuinely pin the new behaviour rather than restating it. CI — two red checks, neither introduced by this PR:
Verdict: LGTM on the code — well-scoped, low-risk, well-tested. I can't register a GitHub approval (own-PR restriction), and I am not auto-merging: Generated by Claude Code |
Remediation review — verdict: sound, one config blocker to clearAutomated pass over this PR (diff, CI checks, CodeRabbit thread). The change itself is correct and well-tested; the only thing standing between it and merge is a pre-existing CI false positive unrelated to your diff. Change assessment ✅The batching is right, and CodeRabbit's confirmation of the perf reasoning matches the CI:
|
Canonical issue
Closes #1181
Outcome
LoggingService._write_to_files()now issues onewrite()per output fileinstead of one per log entry.
aiofilesis a thread-pool shim, not a native-async file layer. Every method onits file objects is generated by
_make_delegate_method:Each
await f.write(...)is therefore a full executor round-trip -- submit,context-switch to a worker thread, write, hop back to the loop. Cost scales with
the number of calls, not the number of bytes.
LoggingServicedefaults to'buffer_size': 100andflush_logs()drains thewhole buffer at once, so a single flush previously cost:
structured_logs.jsonlerror_logs.jsonl(all-ERROR batch)Flushes fire on a 30s timer and whenever the buffer fills, so this is the
steady-state path.
Scope
One function,
src/youtube_extension/backend/services/logging_service.py:372.What this does not change: output bytes, file paths,
'a'append mode,ERROR/CRITICAL routing to the separate file, or the surrounding
try/except.Only the number of
write()calls changes.Design notes
Why not add an empty-batch guard around the structured write?
The per-entry loop still opened
structured_logs.jsonlfor an empty batch,which creates the file as a side effect. Guarding the open would change that
observable behaviour for a path that already costs nothing (
''.join([])is'', and a singlewrite('')is one no-op round-trip).test_empty_batch_does_not_raisepins the safety of that path without changing it. The existing
if error_logs:guard on the error file is untouched.
Why
''.join(...)rather thanwritelines()?aiofiles'writelinesis delegated the same way, and CPython'swritelinesloops internally -- so it is one executor round-trip either way, but
''.joinmakes the single-call property explicit and directly assertable in a test.
Memory. The batch is bounded by
buffer_size(default 100 entries), which isalready fully materialised in
log_bufferbefore this function is called. Joiningit adds one transient string of the same order as the data already in memory.
Risk
Low. No public API change, no behaviour change beyond call count.
The failure mode of the old code (partial batch written, then an exception) is
strictly worse than the new one -- a single
write()cannot interleave apartial batch with a concurrent flush.
Verification
At head
60ae14e84d937235520a4470918a2e4658932ad9:Non-vacuity — the new tests were run against the per-entry loop they replace
and confirmed to fail:
The
24in the second case is the point of the change: 12 entries × 2 files.Tests added (
TestLoggingServiceWriteToFiles):test_batches_structured_logs_into_one_writewrite()for 25 entriestest_batches_error_logs_into_one_writewrite()for an all-ERROR batchtest_writes_every_entry_exactly_oncetest_appends_rather_than_truncatingtest_error_logs_routed_to_separate_filetest_no_error_content_written_when_no_error_logstest_empty_batch_does_not_raiseProduction evidence
logging_servicehas 11 importers, including request-path middleware:Enclosing function confirmed genuinely
async(line 372), so the awaits are realevent-loop yields rather than a
run_in_executorworker where blocking would becorrect.
Agent handoff
Reviewed by
@coderabbitai. Second in a series of bounded-IO performance fixes;follows #1152 (bounded Redis tag writes) and #1170 (bounded Firestore cleanup).